[BUG] Divide by zero error during retrieval

[jimpick]

Note: For security-related bugs/issues, please follow the security policy.

Describe the bug

While doing retrieval testing on Lotus built of the master branch, the retrieval stopped suddenly and it appears the API stopped listening on port 1234 - but the daemon kept running, and it appears the API comes back.

Here are my logs:

Mar 28 05:29:02 Retrieving f0157535 1639420 bafykbzacedoze6ckqa36rd7sxv7pcpjhugbbdnfssif2meiivcykvcvqup5h2
Mar 28 05:29:02   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
Mar 28 05:29:02                                  Dload  Upload   Total   Spent    Left  Speed
Mar 28 05:29:02 ^M  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0^M100   556  100   378  100   178  14000   6592 --:--:-- --:--:-- --:--:-- 20592
Mar 28 05:29:02 {"jsonrpc":"2.0","result":{"Err":"","Root":{"/":"bafykbzacedoze6ckqa36rd7sxv7pcpjhugbbdnfssif2meiivcykvcvqup5h2"},"Piece":null,"Size":34359738368,"MinPrice":"2","UnsealPrice":"2","PaymentInterval":1048576,"PaymentIntervalIncrease":1048576,"Miner":"f0157528","MinerPeer":{"Address":"f0157535","ID":"12D3KooWAypLydzLVAWD9aURXSvgxGdfAEuq7cUGVLkbmxK3cMLC","PieceCID":null}},"id":1}
Mar 28 05:29:02 > Recv: 0 B, Paid 0 FIL, ClientEventOpen (DealStatusNew)
Mar 28 05:29:02 > Recv: 0 B, Paid 0 FIL, ClientEventDealProposed (DealStatusWaitForAcceptance)
Mar 28 05:29:02 > Recv: 0 B, Paid 0 FIL, ClientEventUnsealPaymentRequested (DealStatusAccepted)
Mar 28 05:29:03 > Recv: 0 B, Paid 0 FIL, ClientEventPaymentChannelAddingFunds (DealStatusPaymentChannelAllocatingLane)
Mar 28 05:29:03 > Recv: 0 B, Paid 0 FIL, ClientEventLaneAllocated (DealStatusOngoing)
Mar 28 05:29:03 > Recv: 0 B, Paid 0 FIL, ClientEventPaymentRequested (DealStatusFundsNeeded)
Mar 28 05:29:03 > Recv: 0 B, Paid 0 FIL, ClientEventSendFunds (DealStatusSendFunds)
Mar 28 05:29:03 > Recv: 0 B, Paid 0 FIL, ClientEventVoucherShortfall (DealStatusCheckFunds)
Mar 28 05:29:03 > Recv: 0 B, Paid 0 FIL, ClientEventPaymentChannelAddingFunds (DealStatusPaymentChannelAddingFunds)
Mar 28 05:32:30 > Recv: 0 B, Paid 0 FIL, ClientEventPaymentChannelReady (DealStatusOngoing)
Mar 28 05:32:30 > Recv: 0 B, Paid 0 FIL, ClientEventPaymentRequested (DealStatusFundsNeeded)
Mar 28 05:32:30 > Recv: 0 B, Paid 0 FIL, ClientEventSendFunds (DealStatusSendFunds)
Mar 28 05:32:31 Success
Mar 28 05:32:31 0.36user 0.05system 3:29.18elapsed 0%CPU (0avgtext+0avgdata 72528maxresident)k
Mar 28 05:32:31 32inputs+0outputs (1major+11499minor)pagefaults 0swaps
Mar 28 05:32:31 ERROR: dial tcp 0.0.0.0:1234: connect: connection refused
Mar 28 05:32:31 

I found an interesting panic in the Lotus node logs:

panic: division by zero

goroutine 103439970 [running]:
math/big.nat.div(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc03d11c910, 0x0, 0x1, 0x0, ...)
        /usr/local/go/src/math/big/nat.go:656 +0x490
math/big.(*Int).QuoRem(0xc066bbbe00, 0xc066bbbdc0, 0xc066bbbbc0, 0xc02481adc8, 0x0, 0x0)
        /usr/local/go/src/math/big/int.go:239 +0xbf
math/big.(*Int).Div(0xc066bbbe00, 0xc066bbbdc0, 0xc066bbbbc0, 0xc066bbbdc0)
        /usr/local/go/src/math/big/int.go:250 +0x6a
github.com/filecoin-project/go-state-types/big.Div(0xc066bbbdc0, 0xc066bbbbc0, 0xc066bbbdc0)
        /home/ubuntu/go/pkg/mod/github.com/filecoin-project/go-state-types@v0.1.0/big/int.go:78 +0x67
github.com/filecoin-project/go-fil-markets/retrievalmarket/impl/clientstates.glob..func22(0xc0462c6240, 0x0, 0x0)
        /home/ubuntu/go/pkg/mod/github.com/filecoin-project/go-fil-markets@v1.1.9/retrievalmarket/impl/clientstates/client_fsm.go:251 +0xdb
reflect.Value.call(0x2cc28e0, 0x333e178, 0x13, 0x3090082, 0x4, 0xc066bbbd00, 0x1, 0x1, 0xc02481b110, 0x58414c, ...)
        /usr/local/go/src/reflect/value.go:476 +0x8c7
reflect.Value.Call(0x2cc28e0, 0x333e178, 0x13, 0xc066bbbd00, 0x1, 0x1, 0x34cd4c0, 0xc03d11c801, 0x50a9a6ff0dc15387)
        /usr/local/go/src/reflect/value.go:337 +0xb9
github.com/filecoin-project/go-statemachine/fsm.applyAction(0x2e10600, 0xc0462c6240, 0x16, 0x2c9b7e0, 0x34cd660, 0x0, 0x0, 0x0, 0x3553620, 0xc0000ba008, ...)
        /home/ubuntu/go/pkg/mod/github.com/filecoin-project/go-statemachine@v0.0.0-20200925024713-05bd7c71fbfe/fsm/eventprocessor.go:173 +0x24c
github.com/filecoin-project/go-statemachine/fsm.eventProcessor.Apply(0x3582ac0, 0x304eae0, 0x30aa72a, 0x6, 0xc032f2aa20, 0xc032f2aa50, 0x2eebbe0, 0xc053c0e580, 0x2e10600, 0xc0462c6240, ...)
        /home/ubuntu/go/pkg/mod/github.com/filecoin-project/go-statemachine@v0.0.0-20200925024713-05bd7c71fbfe/fsm/eventprocessor.go:140 +0x41b
github.com/filecoin-project/go-statemachine/fsm.fsmHandler.Plan(0x3582ac0, 0x304eae0, 0x30aa72a, 0x6, 0xc032aef220, 0xc032f0c540, 0x3548f20, 0xc032f2aa80, 0xc032f2aab0, 0x2e10740, ...)
        /home/ubuntu/go/pkg/mod/github.com/filecoin-project/go-statemachine@v0.0.0-20200925024713-05bd7c71fbfe/fsm/fsm.go:86 +0x1ae
github.com/filecoin-project/go-statemachine.(*StateMachine).run.func1(0x2e10600, 0xc0462c6240, 0x16, 0x1)
        /home/ubuntu/go/pkg/mod/github.com/filecoin-project/go-statemachine@v0.0.0-20200925024713-05bd7c71fbfe/machine.go:71 +0x97
github.com/filecoin-project/go-statemachine.(*StateMachine).mutateUser.func1(0xc066bbbce0, 0x1, 0x1, 0xc066bbbce0, 0x10000c03741b840, 0x7f9e9b78bf78)
        /home/ubuntu/go/pkg/mod/github.com/filecoin-project/go-statemachine@v0.0.0-20200925024713-05bd7c71fbfe/machine.go:121 +0x9a
reflect.callReflect(0xc05af04630, 0xc02481b9c0, 0xc02481b9a8)
        /usr/local/go/src/reflect/value.go:565 +0x32a
reflect.makeFuncStub(0xc0462c6240, 0x0, 0x0, 0xc066bbbcc0, 0xc02481bbf8, 0x610ca7, 0xc02b690cc0, 0xc05af04630, 0xc066bbbcc0, 0x800000018, ...)
        /usr/local/go/src/reflect/asm_amd64.s:20 +0x42
reflect.Value.call(0x2cc28e0, 0xc05af04630, 0x13, 0x3090082, 0x4, 0xc02481bcf8, 0x1, 0x1, 0x3511460, 0xc05af046c0, ...)
        /usr/local/go/src/reflect/value.go:476 +0x8c7
reflect.Value.Call(0x2cc28e0, 0xc05af04630, 0x13, 0xc02481bcf8, 0x1, 0x1, 0x0, 0xc02481bd10, 0xb00276)
        /usr/local/go/src/reflect/value.go:337 +0xb9
github.com/filecoin-project/go-statestore.cborMutator.func1(0xc01f3302c0, 0x2a3, 0x2c0, 0xc01f3302c0, 0x2a3, 0x2c0, 0x0, 0x0)
        /home/ubuntu/go/pkg/mod/github.com/filecoin-project/go-statestore@v0.1.1-0.20210311122610-6c7a5aedbdea/state.go:89 +0x1f4
github.com/filecoin-project/go-statestore.(*StoredState).mutate(0xc053975200, 0xc066bbbb20, 0xc066bbbb20, 0x2cc28e0)
        /home/ubuntu/go/pkg/mod/github.com/filecoin-project/go-statestore@v0.1.1-0.20210311122610-6c7a5aedbdea/state.go:66 +0xe6
github.com/filecoin-project/go-statestore.(*StoredState).Mutate(0xc053975200, 0x2cc28e0, 0xc05af04630, 0x2cc2801, 0x2cc28e0)
        /home/ubuntu/go/pkg/mod/github.com/filecoin-project/go-statestore@v0.1.1-0.20210311122610-6c7a5aedbdea/state.go:49 +0x4d
github.com/filecoin-project/go-statemachine.(*StateMachine).mutateUser(0xc02ea214a0, 0xc053c0e5c0, 0x0, 0x0)
        /home/ubuntu/go/pkg/mod/github.com/filecoin-project/go-statemachine@v0.0.0-20200925024713-05bd7c71fbfe/machine.go:125 +0x1e5
github.com/filecoin-project/go-statemachine.(*StateMachine).run(0xc02ea214a0)
        /home/ubuntu/go/pkg/mod/github.com/filecoin-project/go-statemachine@v0.0.0-20200925024713-05bd7c71fbfe/machine.go:70 +0x2dc
created by github.com/filecoin-project/go-statemachine.(*StateGroup).loadOrCreate
        /home/ubuntu/go/pkg/mod/github.com/filecoin-project/go-statemachine@v0.0.0-20200925024713-05bd7c71fbfe/group.go:133 +0x3bc

Version (run lotus version):

$ lotus version
Daemon:  1.6.0-dev+mainnet+git.885ecb97a+api1.1.0
Local: lotus version 1.6.0-dev+mainnet+git.885ecb97a

[jimpick]

Here's the line in question:

https://github.com/filecoin-project/go-fil-markets/blob/v1.1.9/retrievalmarket/impl/clientstates/client_fsm.go#L251

deal.PricePerByte must be zero when it hits that code.

[jimpick]

It's also odd that lotus client retrieve prints "Success" even though it failed in a panic.